<html>
<head><meta charset="utf-8"><title>profiling rust-analyzer · t-compiler/rust-analyzer · Zulip Chat Archive</title></head>
<h2>Stream: <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/index.html">t-compiler/rust-analyzer</a></h2>
<h3>Topic: <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html">profiling rust-analyzer</a></h3>

<hr>

<base href="https://rust-lang.zulipchat.com">

<head><link href="https://rust-lang.github.io/zulip_archive/style.css" rel="stylesheet"></head>

<a name="184729408"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184729408" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184729408">(Jan 03 2020 at 12:26)</a>:</h4>
<p><span class="user-mention" data-user-id="133169">@matklad</span>  I've had a look at profiles of rust-analyzer (when adding just whitespace) and I have a hypothesis wrt. the unaccounted time that we saw (or at least some of it). I looked at <code>Module::from_file</code> that regularly takes &gt;60ms and it seems that this is coming from <code>db.crate_def_map</code> even though I haven't seen <code>crate_def_map_query</code> itself being called. I'm wondering if this time could be spent in salsa -- trying to figure out if something needs to be recomputed or not? (and then deciding that it doesn't, so in the end <code>create_def_map_query</code> is never called)<br>
My experiment: <a href="https://github.com/michalt/rust-analyzer/commit/57dee141c34070e8ddf2c870908a01e3ce073eed" target="_blank" title="https://github.com/michalt/rust-analyzer/commit/57dee141c34070e8ddf2c870908a01e3ce073eed">https://github.com/michalt/rust-analyzer/commit/57dee141c34070e8ddf2c870908a01e3ce073eed</a><br>
If my understanding is correct then it seems that this is a bit of a blind spot for how we currently use <code>ra_prof</code> -- we don't know if some unaccounted recomputation is taking long or if the time is spent in salsa. We could potentially add a bunch of more <code>profile</code> around calls to <code>db</code>, but it does feel that this should belong to salsa itself, which has all the information needed to account the time to the right place.</p>
<p>What do you think? Perhaps I'm misunderstanding something? (also do you know whether salsa has some similar profiling mechanism that we could use?)</p>



<a name="184729572"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184729572" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184729572">(Jan 03 2020 at 12:30)</a>:</h4>
<p>Yeah, that does sound like a resaonable hypothesis. Specifically, salsa might spend quite some time validating that the answer has not changed, without actually recomputing the function. I think the best way to test this hypothesis is to point <code>rust-analyzer</code> to a custom build of <code>salsa</code> (using <code>[patch]</code> section in Cargo.toml) and adding profile calls to salsa itself.</p>
<p>Salsa checks happen here: <a href="https://github.com/salsa-rs/salsa/blob/37a3650aef84883f42358d44960a5f2421acb9ba/src/derived/slot.rs#L144-L145" target="_blank" title="https://github.com/salsa-rs/salsa/blob/37a3650aef84883f42358d44960a5f2421acb9ba/src/derived/slot.rs#L144-L145">https://github.com/salsa-rs/salsa/blob/37a3650aef84883f42358d44960a5f2421acb9ba/src/derived/slot.rs#L144-L145</a></p>



<a name="184729721"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184729721" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184729721">(Jan 03 2020 at 12:33)</a>:</h4>
<p>A further steps here would be:</p>
<ul>
<li>figure out why validation takes so long? Perhaps we, for some reason, have too many dependencies which need to be validated? Validation costs can be reduced by using <a href="https://github.com/salsa-rs/salsa/blob/ae9ab75384a6b946263507c71790b8927da05244/src/durability.rs" target="_blank" title="https://github.com/salsa-rs/salsa/blob/ae9ab75384a6b946263507c71790b8927da05244/src/durability.rs">durability</a></li>
<li>run some cpu profiling on salsa, to check if there's some low-hanging fruit to optimize validation</li>
</ul>



<a name="184729987"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184729987" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184729987">(Jan 03 2020 at 12:38)</a>:</h4>
<p>Cool, sounds like a plan! Thanks for the pointers re using a custom salsa build!</p>



<a name="184729991"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184729991" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184729991">(Jan 03 2020 at 12:38)</a>:</h4>
<p>Oh, one useful thing to do would be merge the changes in your gist. I think we can do this nicely in this way:</p>
<ul>
<li>rename <code>crate_def_map</code> and corresponding profile to <code>compute_crate_def_map</code></li>
<li>add a <code>#[salsa::transparent]</code> <code>crate_def_map</code> query, which forwards to <code>compute_</code> one, with a profile call on top</li>
</ul>



<a name="184730022"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184730022" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184730022">(Jan 03 2020 at 12:39)</a>:</h4>
<p>That way, we'll see somthing like</p>
<div class="codehilite"><pre><span></span>crate_def_map 9000
  compute_crate_def_map 9000
</pre></div>


<p>or </p>
<div class="codehilite"><pre><span></span>crate_def_map 600
// nothing here, we know it&#39;s validation!
</pre></div>



<a name="184730110"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184730110" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184730110">(Jan 03 2020 at 12:40)</a>:</h4>
<p>Oh, nice! I was thinking how we could do this nicely, but didn't know about <code>salsa::transparent</code>.</p>



<a name="184730932"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184730932" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> Florian Diebold <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184730932">(Jan 03 2020 at 12:57)</a>:</h4>
<p><code>crate_def_map</code> probably does have a huge amount of dependencies, doesn't it</p>



<a name="184731438"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184731438" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184731438">(Jan 03 2020 at 13:04)</a>:</h4>
<p>I wouldn't expect a huge amount: most deps should be const, so we should be left with a raw_items per file</p>



<a name="184731664"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184731664" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184731664">(Jan 03 2020 at 13:08)</a>:</h4>
<p>Here's what I came up with: <a href="https://github.com/rust-analyzer/rust-analyzer/pull/2731" target="_blank" title="https://github.com/rust-analyzer/rust-analyzer/pull/2731">https://github.com/rust-analyzer/rust-analyzer/pull/2731</a> -- do let me know if I misunderstood your suggestion! :)</p>



<a name="184756121"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184756121" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184756121">(Jan 03 2020 at 18:32)</a>:</h4>
<p>I've added some logging to salsa: <a href="https://github.com/michalt/salsa/commit/b9c75b79acf9951b8d96011c682cf9c49bdbb49d" target="_blank" title="https://github.com/michalt/salsa/commit/b9c75b79acf9951b8d96011c682cf9c49bdbb49d">https://github.com/michalt/salsa/commit/b9c75b79acf9951b8d96011c682cf9c49bdbb49d</a> and it does seem that it's mostly validation. But it's not trivial to understand if some particular thing is expensive or if it's just the sheer number of transitive dependencies. (LMK if you have any suggestions/suspicions) Perhaps salsa should also collect some profiling stats itself?<br>
Anyway, I'll try to do some profiling with <code>perf</code> over the weekend.</p>



<a name="184759147"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184759147" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184759147">(Jan 03 2020 at 19:10)</a>:</h4>
<blockquote>
<p>or if it's just the sheer number of transitive dependencies. </p>
</blockquote>
<p>A good thing would be to <em>check</em> how many dependencies are there. As I've mentioned above, I wouldn't expect <em>that</em> many dependencies for a crate_def_map query</p>



<a name="184760399"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184760399" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> Laurențiu <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184760399">(Jan 03 2020 at 19:26)</a>:</h4>
<p>Would it be worth increasing <code>RA_LRU_CAP</code> to be sure that's not causing it?</p>



<a name="184760612"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184760612" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184760612">(Jan 03 2020 at 19:28)</a>:</h4>
<p>We might try to do this to rule it out for sure, but I don't think its an issue: otherwise, we'd see a number of lru queries in the profile</p>



<a name="184859348"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184859348" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184859348">(Jan 05 2020 at 18:32)</a>:</h4>
<p>I made some progress with understanding what is taking so much time and it seems that the graph is much larger than I expected. It seems that the single <code>ComputeCrateDefMapQuery</code> triggers checking about 62k memoized values in salsa: <a href="https://github.com/michalt/rust-analyzer/commit/25167ed846c24de3604a233f0d511237cf363f7c" target="_blank" title="https://github.com/michalt/rust-analyzer/commit/25167ed846c24de3604a233f0d511237cf363f7c">https://github.com/michalt/rust-analyzer/commit/25167ed846c24de3604a233f0d511237cf363f7c</a><br>
We process about ~1.5k <code>FileId</code>s (even though rust-analyzer has less than 600 Rust files..?) and ~19k <code>MacroFile</code>s (!!!), which seem to be the main culprit here (we end up with roughly ~20k checks for each of <code>AstIdMapQuery</code>, <code>RawItemsQuery</code> and <code>MacroArgQuery</code>)<br>
I have no idea why we have so many<code>FileId</code>s compared to the actual Rust files in rust analyzer. Regarding <code>MacroFile</code>, it seems that we create a separate <code>MacroFile</code> per macro call -- is that correct? What is the reason for this?<br>
Anyway, please do have a look if I missed/misunderstood something!</p>



<a name="184859681"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184859681" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184859681">(Jan 05 2020 at 18:42)</a>:</h4>
<blockquote>
<p>we create a separate MacroFile per macro call -- is that correct? What is the reason for this?</p>
</blockquote>
<p>Yes, each macro call creates a virtual file. We use this setup to allow incremental macro exansion, so that in</p>
<div class="codehilite"><pre><span></span>top_level_macro_call! {
  fn foo() { body }
}
</pre></div>


<p>changes to the <code>body</code> do not invalidate the raw items for the containing file</p>



<a name="184859695"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184859695" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184859695">(Jan 05 2020 at 18:43)</a>:</h4>
<p>And yes, I would expact more macro files than real files, but the numbers you show do seem excessive. Especially given that there are fewer real files at all :D</p>



<a name="184859704"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184859704" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184859704">(Jan 05 2020 at 18:43)</a>:</h4>
<p>I guess with this logging the next logical step is to minize example and to see why we get such amplification</p>



<a name="184859755"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184859755" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184859755">(Jan 05 2020 at 18:44)</a>:</h4>
<p>You can use <code>featureFlags: { "withSysroot": false }</code> <a href="https://github.com/rust-analyzer/rust-analyzer/blob/e4d217074d1f2c922cf8c5a247ca05fa06b0b7ed/editors/code/src/client.ts#L41" target="_blank" title="https://github.com/rust-analyzer/rust-analyzer/blob/e4d217074d1f2c922cf8c5a247ca05fa06b0b7ed/editors/code/src/client.ts#L41">flag</a> to exclude standard library, which should help with minimization</p>



<a name="184861066"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184861066" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184861066">(Jan 05 2020 at 19:23)</a>:</h4>
<p>Quick question: what happens for nested macros (a macro expands into another macro call) -- do we create 1 or more such virtual files?</p>



<a name="184861146"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184861146" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184861146">(Jan 05 2020 at 19:25)</a>:</h4>
<p>Yup</p>



<a name="184861151"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184861151" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184861151">(Jan 05 2020 at 19:25)</a>:</h4>
<p>So, a recursive macro can indeed create a deep tower of files</p>



<a name="184861284"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184861284" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184861284">(Jan 05 2020 at 19:28)</a>:</h4>
<p>Oh interesting!</p>



<a name="184861368"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184861368" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> michalt <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184861368">(Jan 05 2020 at 19:30)</a>:</h4>
<p>I'll play around with some small crate (as you suggested) and see what we can learn. Thanks!</p>



<a name="184960189"></a>
<h4><a href="https://rust-lang.zulipchat.com#narrow/stream/185405-t-compiler/rust-analyzer/topic/profiling%20rust-analyzer/near/184960189" class="zl"><img src="https://rust-lang.github.io/zulip_archive/assets/img/zulip.svg" alt="view this post on Zulip" style="width:20px;height:20px;"></a> matklad <a href="https://rust-lang.github.io/zulip_archive/stream/185405-t-compiler/rust-analyzer/topic/profiling.20rust-analyzer.html#184960189">(Jan 06 2020 at 21:46)</a>:</h4>
<p>For the record, the result of <span class="user-mention silent" data-user-id="252272">michalt</span> 's investigation is this this epic win of a PR: <a href="https://github.com/rust-analyzer/rust-analyzer/pull/2753#issue-359719510" target="_blank" title="https://github.com/rust-analyzer/rust-analyzer/pull/2753#issue-359719510">https://github.com/rust-analyzer/rust-analyzer/pull/2753#issue-359719510</a></p>



<hr><p>Last updated: Aug 07 2021 at 22:04 UTC</p>
</html>